1% 가 겪는 레이턴시

Supply 그룹에서는 Feature Flag 도입 후 A/B 테스트 실험의 활용도를 높이기 위해 evaluation 결과 적재 인프라 지원이 필요했습니다. 이를 지원하기 위해 기존에 사용 중인 오픈소스 go-feature-flag 의 export 기능을 활용하여 각 파드에서 분 단위로 S3에 flag evaluation 결과를 적재하여 실험 분석 인프라를 개발하게 됐습니다. 1ms 내외의 p95 latency의 저지연 API지만 간헐적으로 S3 export 재시도 문제와 p99 latency가 3초 이상으로 치솟는 이슈가 발생했습니다. 5월 1일 하루 기준으로 Feature Flag evaluation API의 총 호출 수는 6850만 건으로, 약 68만(p99)번의 호출에서는 3초 이상의 지연을 겪는 상황이었습니다. evaluation API는 본래 호출할 API(e.g 베네핏허브 메인 화면 조회)의 사이에 호출되는 것으로 메인 API latency에는 최소한의 영향을 주도록 개선이 필요했습니다.

현재 Feature Flag에서 사용 중인 인프라는 flag 메타데이터를 저장하는 redis 와 evaluation 결과를 저장하는 s3 가 있습니다. redis에 저장된 메타데이터를 1분에 한 번씩 조회하여 local cache에 저장한 뒤 evaluation에 사용하기 때문에 다수의 pod에서 1분에 한 번씩 조회한들 3초 이상의 p99 latency를 초래하는 요인으로 보긴 어려웠습니다. 실제로 Feature Flag 전용 레디스를 별도로 운영하기 때문에 latency 지표를 통해 위 상황과는 무관한 점을 쉽게 파악할 수 있었습니다.

남은 건 S3인데 문제에 딥다이브 하면서 실제로는 두 가지 레이턴시 문제가 혼재돼 있고 두 문제 모두 mutex, 즉 공유 자원 락과 관련 있는 걸 확인했습니다.

문제 1 - p99 spike: 특정 순간에 p99가 수 초~수십 초로 치솟는 현상
문제 2 - max 레이턴시 baseline: spike를 해결한 뒤에도 flush마다 60-70ms의 블로킹이 남아 있는 현상

mutex는 한 번에 하나의 고루틴만 통과할 수 있게 하는 잠금장치로, 락을 건 채 오래 대기 시 후속으로 실행 준비 중인 모든 스레드가 기다려야 합니다. 이 글은 mutex 락과 관련된 두 문제를 순서대로 추적하고 해결한 과정을 정리합니다.

Feature Flag Evaluation API의 구조

Feature Flag Evaluation API는 클라이언트로부터 특정 flag key에 대한 평가 요청을 받으면 local cache에서 flag 데이터를 조회하여 boolean, string, int 등의 값을 반환하는 구조입니다. source data는 1분에 한번씩 Redis 조회로 가져오며 latency는 sub-millisecond 수준이므로 평상시에 p95가 1ms 이하인 것도 자연스러운 일이었습니다.

Feature Flag 라이브러리(go-feature-flag)는 모든 evaluation 결과를 이벤트로 기록하며 일정 조건이 충족되면 이 이벤트들을 S3에 내보내는 구조를 갖습니다. 평소에는 이벤트를 메모리 버퍼에 쌓기만 하므로 API 응답에 영향을 주지 않지만 flush가 발생하는 순간에는 상황이 달라집니다.

flush 메커니즘

go-feature-flag 라이브러리의 DataExporter는 60초마다 실행되는 타이머 기반과 메모리 버퍼에 이벤트가 100,000개 쌓이면 발생하는 버퍼 기반으로 flush를 트리거합니다. 두 경우 모두 flush 과정에서 mutex 획득 후 동기식으로 S3 Export를 실행합니다.

AddEvent()는 모든 evaluation 요청마다 호출되며 버퍼에 이벤트를 추가하기 위해 동일한 mutex를 사용합니다. flush가 진행되는 동안 mutex가 잠겨 있으므로 그 사이에 들어오는 다른 모든 요청의 AddEvent() 호출이 mutex에서 대기하고 이것이 곧 API 레이턴시 증가로 이어집니다.

text
AddEvent() 호출
     │
     ▼
mutex.Lock()  ◀── flush 중이면 여기서 대기
     │
     ▼
len(cache) >= 100,000?
     │           │
    YES          NO
     │           │
     ▼           ▼
  flush()     cache에 이벤트 추가
  (동기식)    
     │
     ▼
S3Exporter.Export()
     │
     └─▶ S3 Upload (~60-70ms)

여기까지가 두 문제의 공통 배경입니다. flush 중 mutex가 잠기기 때문에 다른 요청이 대기하는 구조적 특성이 문제 1과 문제 2의 출발점이었습니다.

문제 1: p99 레이턴시 — mutex 물고 sleep 하는 Jitter

flush 자체가 느린지, 다른 요인으로 느려지는 것인지 확인할 필요가 있었습니다. 디버깅 로그를 추가하여 실제 트래픽을 분석한 결과는 아래와 같습니다.

S3 업로드는 60-70ms 밖에 안 걸렸고 버퍼가 100,000개에 도달한 적도 없었습니다. 그렇다면 3초라는 latency는 어디서 발생하는 걸까요? 애플리케이션 코드에 추가된 S3 Exporter의 applyJitter() 함수에 있었습니다.

위 에러는 여러 pod가 동시에 S3로 업로드 시 발생하는 thundering herd 문제로 S3가 503을 반환하며 최대 재시도 횟수를 초과시 발생합니다. 문제 해결책으로 각 pod마다 재시도 시 0~7초의 랜덤한 간격(jitter) 을 추가하여 S3에 요청이 몰리는 상황을 방지하려 했고 실제로 S3 throttling 이슈는 해결할 수 있었습니다. 하지만 jitter의 sleep이 mutex를 잡은 상태에서 실행되는 점이 문제였습니다. flush 동안 mutex를 잡은 상태에서 최대 7초간 sleep 하니, 그 시간 동안 다른 모든 요청의 AddEvent()가 대기하게 됩니다.

go
func (f *S3Exporter) applyJitter(ctx context.Context) error {
    if f.MaxJitterMs <= 0 {
        return nil
    }
    jitter := time.Duration(rand.IntN(f.MaxJitterMs)) * time.Millisecond
    select {
    case <-ctx.Done():
        return fmt.Errorf("interrupted")
    case <-time.After(jitter):  // ← 최대 7초 sleep
        return nil
    }
}

Jitter 비활성화

가장 즉각적인 효과를 가져온 건 Jitter를 임시로 비활성화한 PR이었습니다. 원인이 Jitter라는 확신이 생긴 뒤 Export 함수에서 applyJitter() 호출을 주석 처리하는 단순한 변경이었지만 효과는 극적이었습니다. 배포 직후 일 최대 레이턴시가 55초에서 약 200ms 수준으로 떨어졌고, 이후 지속적으로 안정적인 수치를 유지했습니다.

jitter 제거 후 thundering herd 이슈는 export 주기를 늘리는 식으로 완화할 수 있었습니다. 기존에는 매 1분마다 export가 발생하여 여러 파드가 동시에 flush할 빈도가 높았지만 이 주기를 3분으로 늘리면서 동시 flush 빈도를 줄여 S3 throttling 에러를 안정적으로 운영할 수 있었습니다. (완전히 제거할 수는 없었지만 그 빈도는 거의 없는 수준으로 줄었습니다.)

문제 2: max 레이턴시 — 동기 flush가 API를 블락

Jitter를 비활성화하고 export 주기를 조절하여 p99 spike 이슈는 해결했지만 max latency라는 또 다른 문제가 있었습니다. flush 중에는 S3 업로드 시간만큼 mutex가 잠겨 있으므로 모든 요청이 그만큼 대기하여 간헐적으로 max latency가 튀는 현상이었습니다. flush마다 모든 API 요청이 일제히 멈추는 것은 여전히 바람직하지 않았습니다.

AsyncExporter 래퍼 — 비동기 전환

결국 근본적인 개선은 Export 과정의 비동기 전환이라 판단했습니다. 기존에는 flush 트리거 시 S3 업로드가 완료까지 mutex를 잡고 기다렸지만, AsyncExporter wrapper를 도입하여 Export() 호출이 이벤트를 채널로 전달하고 즉시 리턴하도록 변경했습니다. mutex 해제 자체는 라이브러리(Scheduler)가 하지만 Export()가 즉시 리턴하므로 Scheduler의 mutex hold time이 마이크로초 단위로 줄어들고, S3 업로드는 별도 background goroutine에서 비동기로 처리됩니다.

왜 라이브러리 수정이 아닌 래퍼인가

처음에는 go-feature-flag 라이브러리의 최신 버전 업그레이드를 검토했지만, 최신 버전(v1.52.1)에도 DataExporter 스케줄러가 flush 시 mutex를 잡은 채 동기식으로 Export하는 패턴이 존재했습니다. 업스트림 업그레이드만으로는 구조적 해결이 불가능했습니다. 라이브러리 코드를 포크해서 직접 수정하는 방법도 고려했지만 유지보수 부담이 컸기 때문에 최종적으로는 라이브러리가 제공하는 Exporter 인터페이스를 구현하는 비동기 래퍼를 만들기로 결정했습니다. 기존 S3Exporter를 감싸는 AsyncExporter wrapper를 만들어 Export 호출을 비동기로 위임하는 방식으로 비동기 export를 구현했습니다.

동작 흐름

text
Scheduler.flush()
    │
    ▼
AsyncExporter.Export()
    │  이벤트를 채널로 전달하고 즉시 리턴
    │
    ▼
buffered channel (size: 10)
    │
    ▼
background goroutine
    │  채널에서 이벤트를 꺼내 실제 업로드 수행
    │
    ▼
S3Exporter.Export()  →  S3 업로드 (수백 ms)

스케줄러가 AsyncExporter.Export()를 호출하면 이벤트 데이터를 채널로 전달 후 즉시 리턴합니다. 실제 S3 업로드는 별도의 background goroutine이 채널에서 job을 꺼내 처리합니다. 스케줄러 입장에서 Export는 채널 send 한 번으로 끝나므로 mutex hold time이 마이크로초 단위로 줄어듭니다.

Export() 메서드의 핵심 구현은 다음과 같습니다:

go
type exportJob struct {
	ctx    context.Context
	events []ffexporter.FeatureEvent
}

type AsyncExporter struct {
	inner     ffexporter.Exporter
	eventsCh  chan exportJob
	...
}

func (a *AsyncExporter) Export(
    ctx context.Context, logger *fflog.FFLogger, events []ffexporter.FeatureEvent,
) error {
    copied := make([]ffexporter.FeatureEvent, len(events))
    copy(copied, events)

    select {
    case a.eventsCh <- exportJob{ctx: ctx, events: copied}:
    default:
        log.Warnf("channel full, dropping %d events", len(events)) // 채널 포화 시 블로킹 없이 drop
    }
    return nil
}

• buffered channel (size 10): export job을 비동기로 전달하는 데 사용됩니다. export 주기가 3분이므로 채널 크기 10은 최대 30분치 배치를 버퍼링할 수 있습니다. 이는 S3 업로드가 30분 이상 연속으로 지연되는 극단적인 상황의 버퍼로, 정상 운영 시에는 채널이 거의 비어 있습니다.
• shallow copy: Export()는 이벤트 슬라이스를 copy()로 shallow copy하여 채널로 전달합니다. FeatureEvent의 Value (any)나 Metadata (map[string]any) 같은 참조 타입 필드가 deep copy되지 않지만 호출자인 Scheduler가 Export() 이후 이벤트를 변경(mutate)하지 않기 때문에 불필요한 deep copy를 피해 복사 비용을 최소화했습니다.
• 채널 포화 시 drop: 버퍼(channel)가 가득 찬 경우 select-default 패턴으로 블로킹 없이 로그 경고를 남기며 해당 배치를 drop합니다. API 요청 처리 경로에서 블로킹이 발생하지 않도록 보장하기 위한 구현이었습니다.

AsyncExporter wrapper를 프로덕션에 배포 후 최악의 경우 25초까지 튀던 max latency를 200ms 내외로 안정화할 수 있었습니다.

오픈소스 기여 — mutex hold time 줄이기

서비스 측 개선과 별개로, 근본 원인인 go-feature-flag 라이브러리 코드의 구조적인 문제도 수정이 필요해보였습니다. DataExporter 스케줄러가 flush 시 mutex를 잡은 채로 Export까지 동기 실행하는 구조로, flush 함수에서 cache를 읽어 Export를 호출하고 다시 cache를 비우는 전체 과정이 하나의 mutex lock 안에서 이루어지고 있었습니다. 이 구간에서 네트워크 I/O가 발생하니 mutex hold time이 불필요하게 길어지는 것이 이슈의 원인이었습니다.

go
// 기존 코드 — ProcessPendingEvents
func (e *eventStoreImpl[T]) ProcessPendingEvents(...) error {
    e.mutex.Lock()
    defer e.mutex.Unlock()   // ← S3 업로드 끝날 때까지 유지
    eventList, _ := e.fetchPendingEvents(consumerID)
    processEventsFunc(...)   // ← S3 업로드 (수십~수백 ms 블로킹)
    e.updateConsumerOffset(...)
}

go
// 변경 후 — 락 분리 (3단계)
func (e *eventStoreImpl[T]) ProcessPendingEvents(...) error {
    // Step 1: 이벤트 조회 (짧은 락)
    e.mutex.Lock()
    eventList, err := e.fetchPendingEvents(consumerID)
    e.mutex.Unlock()

    // Step 2: Export 실행 (락 없음 — 느린 I/O)
    err = processEventsFunc(context.Background(), eventList.Events)

    // Step 3: offset 업데이트 (짧은 락)
    e.mutex.Lock()
    err = e.updateConsumerOffset(consumerID, eventList.NewOffset)
    e.mutex.Unlock()
}

위 문제를 해결하기 위해 PR을 생성했습니다. mutex hold time을 최소화하도록 cache 데이터를 로컬 변수로 복사한 뒤 즉시 mutex를 해제, 실제 Export는 mutex 밖에서 실행하도록 수정하여 Export 과정의 네트워크 I/O가 오래 걸리더라도 다른 goroutine의 AddEvent() 호출이 블로킹되지 않도록 개선했습니다. 해당 PR은 최종적으로 머지되어 오픈소스 기여까지 할 수 있었습니다. 이제 Jitter를 다시 활성화하더라도 sleep이 mutex 밖에서 실행되므로 thundering herd를 방지하면서 API 레이턴시에 영향을 주지 않도록 개선되어 다음 라이브러리 버전 출시 시 프로덕션 코드에 적용을 해보려 합니다.

마무리

개선 과정을 정리해보면 두 문제 모두 mutex를 걸고 I/O를 수행 했다는 동일 원인으로 귀결되었습니다. 처음에는 S3 throttling이나 네트워크 지연이 원인일 것이라 추측했지만 실제로는 lock scope 안에 포함된 slow I/O가 문제였습니다. 문제 1에서는 mutex를 물고 최대 7초간 sleep하는 Jitter, 문제 2에서는 mutex를 잡고 S3 업로드를 수행하는 동기 flush가 원인으로 규모만 달랐을 뿐 패턴은 동일했고 결국 lock scope를 최소화한다는 하나의 원칙으로 두 문제 모두 해결할 수 있었습니다.

운영 중 만난 레이턴시 문제를 파고들다 라이브러리의 근본 원인까지 수정하게 되었고 결과적으로 오픈소스 기여로까지 연결할 수 있었습니다. 서비스 코드뿐 아니라 의존하고 있는 라이브러리까지 딥다이브하며 문제 해결 폭을 더 넓힐 수 있었습니다.

📌200ms 내외로 안정화 된 max latency

Reference

• go-feature-flag
• fix(exporter): reduce mutex hold time in process pending events